Filed by: archaeopteryx [at] coole-files.de
Parsed log: https://treeherder.mozilla.org//logviewer?job_id=320284857&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/S_c3reCIQy-QJCq36Mndug/runs/0/artifacts/public/logs/live_backing.log

[task 2020-10-30T18:23:24.118Z] 18:23:24     INFO - TEST-START | dom/notification/test/mochitest/test_notification_tag.html
[task 2020-10-30T18:23:24.840Z] 18:23:24     INFO - GECKO(3069) | MEMORY STAT | vsize 130550477MB | residentFast 546MB
[task 2020-10-30T18:23:24.876Z] 18:23:24     INFO - TEST-OK | dom/notification/test/mochitest/test_notification_tag.html | took 763ms
[task 2020-10-30T18:23:25.058Z] 18:23:25     INFO - TEST-START | Shutdown
[task 2020-10-30T18:23:25.058Z] 18:23:25     INFO - Passed:  56
[task 2020-10-30T18:23:25.058Z] 18:23:25     INFO - Failed:  0
[task 2020-10-30T18:23:25.058Z] 18:23:25     INFO - Todo:    21
[task 2020-10-30T18:23:25.058Z] 18:23:25     INFO - Mode:    e10s
[task 2020-10-30T18:23:25.059Z] 18:23:25     INFO - Slowest: 1848ms - /tests/dom/notification/test/mochitest/test_bug931307.html
[task 2020-10-30T18:23:25.063Z] 18:23:25     INFO - SimpleTest FINISHED
[task 2020-10-30T18:23:25.064Z] 18:23:25     INFO - TEST-INFO | Ran 1 Loops
[task 2020-10-30T18:23:25.066Z] 18:23:25     INFO - SimpleTest FINISHED
[task 2020-10-30T18:23:25.368Z] 18:23:25     INFO - GECKO(3069) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 554: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2020-10-30T18:23:27.926Z] 18:23:27     INFO - GECKO(3069) | 1604082207921	Marionette	TRACE	Received observer notification xpcom-will-shutdown
[task 2020-10-30T18:23:27.926Z] 18:23:27     INFO - GECKO(3069) | 1604082207923	Marionette	INFO	Stopped listening on port 2828
[task 2020-10-30T18:23:27.928Z] 18:23:27     INFO - GECKO(3069) | 1604082207923	Marionette	DEBUG	Marionette stopped listening
[task 2020-10-30T18:23:33.385Z] 18:23:33     INFO - GECKO(3069) | ==================
[task 2020-10-30T18:23:33.385Z] 18:23:33     INFO - GECKO(3069) | WARNING: ThreadSanitizer: data race (pid=3069)
[task 2020-10-30T18:23:33.385Z] 18:23:33     INFO - GECKO(3069) |   Write of size 1 at 0x7f7c04eb4901 by main thread:
[task 2020-10-30T18:23:33.387Z] 18:23:33     INFO - GECKO(3069) |     #0 mozilla::ShutdownXPCOM(nsIServiceManager*) /builds/worker/checkouts/gecko/xpcom/build/XPCOMInit.cpp:639:27 (libxul.so+0xb25408)
[task 2020-10-30T18:23:33.387Z] 18:23:33     INFO - GECKO(3069) |     #1 NS_ShutdownXPCOM /builds/worker/checkouts/gecko/xpcom/build/XPCOMInit.cpp:564:10 (libxul.so+0xb25265)
[task 2020-10-30T18:23:33.388Z] 18:23:33     INFO - GECKO(3069) |     #2 ScopedXPCOMStartup::~ScopedXPCOMStartup() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:1648:5 (libxul.so+0x63eeff2)
[task 2020-10-30T18:23:33.389Z] 18:23:33     INFO - GECKO(3069) |     #3 operator() /builds/worker/workspace/obj-build/dist/include/mozilla/UniquePtr.h:460:5 (libxul.so+0x63facdf)
[task 2020-10-30T18:23:33.389Z] 18:23:33     INFO - GECKO(3069) |     #4 mozilla::UniquePtr<ScopedXPCOMStartup, mozilla::DefaultDelete<ScopedXPCOMStartup> >::reset(ScopedXPCOMStartup*) /builds/worker/workspace/obj-build/dist/include/mozilla/UniquePtr.h:302:7 (libxul.so+0x63facdf)
[task 2020-10-30T18:23:33.389Z] 18:23:33     INFO - GECKO(3069) |     #5 operator= /builds/worker/workspace/obj-build/dist/include/mozilla/UniquePtr.h:275:5 (libxul.so+0x63f8c2d)
[task 2020-10-30T18:23:33.389Z] 18:23:33     INFO - GECKO(3069) |     #6 XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5300:16 (libxul.so+0x63f8c2d)
[task 2020-10-30T18:23:33.390Z] 18:23:33     INFO - GECKO(3069) |     #7 XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5339:21 (libxul.so+0x63f8f24)
[task 2020-10-30T18:23:33.390Z] 18:23:33     INFO - GECKO(3069) |     #8 mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:45:12 (libxul.so+0x6403272)
[task 2020-10-30T18:23:33.391Z] 18:23:33     INFO - GECKO(3069) |     #9 do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:218:22 (firefox+0xc7c50)
[task 2020-10-30T18:23:33.392Z] 18:23:33     INFO - GECKO(3069) |     #10 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:336:16 (firefox+0xc7c50)
[task 2020-10-30T18:23:33.393Z] 18:23:33     INFO - GECKO(3069) |   Previous read of size 1 at 0x7f7c04eb4901 by thread T15:
[task 2020-10-30T18:23:33.393Z] 18:23:33     INFO - GECKO(3069) |     #0 mozilla::ThreadEventTarget::Dispatch(already_AddRefed<nsIRunnable>, unsigned int) /builds/worker/checkouts/gecko/xpcom/threads/ThreadEventTarget.cpp:55:7 (libxul.so+0xae5c81)
[task 2020-10-30T18:23:33.395Z] 18:23:33     INFO - GECKO(3069) |     #1 nsThread::Dispatch(already_AddRefed<nsIRunnable>, unsigned int) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:708:24 (libxul.so+0xaefe8e)
[task 2020-10-30T18:23:33.395Z] 18:23:33     INFO - GECKO(3069) |     #2 Dispatch /builds/worker/workspace/obj-build/dist/include/nsIEventTarget.h:41:14 (libxul.so+0xaea212)
[task 2020-10-30T18:23:33.395Z] 18:23:33     INFO - GECKO(3069) |     #3 TimerThread::PostTimerEvent(already_AddRefed<nsTimerImpl>) /builds/worker/checkouts/gecko/xpcom/threads/TimerThread.cpp:733:18 (libxul.so+0xaea212)
[task 2020-10-30T18:23:33.396Z] 18:23:33     INFO - GECKO(3069) |     #4 TimerThread::Run() /builds/worker/checkouts/gecko/xpcom/threads/TimerThread.cpp:417:24 (libxul.so+0xae972e)
[task 2020-10-30T18:23:33.397Z] 18:23:33     INFO - GECKO(3069) |     #5 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1197:14 (libxul.so+0xaf1d7e)
[task 2020-10-30T18:23:33.397Z] 18:23:33     INFO - GECKO(3069) |     #6 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:513:10 (libxul.so+0xaf6ff2)
[task 2020-10-30T18:23:33.398Z] 18:23:33     INFO - GECKO(3069) |     #7 mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:302:20 (libxul.so+0x13a85de)
[task 2020-10-30T18:23:33.399Z] 18:23:33     INFO - GECKO(3069) |     #8 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:334:10 (libxul.so+0x133ea6c)
[task 2020-10-30T18:23:33.399Z] 18:23:33     INFO - GECKO(3069) |     #9 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:327:3 (libxul.so+0x133ea6c)
[task 2020-10-30T18:23:33.399Z] 18:23:33     INFO - GECKO(3069) |     #10 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:309:3 (libxul.so+0x133ea6c)
[task 2020-10-30T18:23:33.400Z] 18:23:33     INFO - GECKO(3069) |     #11 nsThread::ThreadFunc(void*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:442:10 (libxul.so+0xaee621)
[task 2020-10-30T18:23:33.400Z] 18:23:33     INFO - GECKO(3069) |     #12 _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5 (libnspr4.so+0x4500b)
[task 2020-10-30T18:23:33.402Z] 18:23:33     INFO - GECKO(3069) |   Location is global 'gXPCOMThreadsShutDown' of size 1 at 0x7f7c04eb4901 (libxul.so+0x00000b11f901)
[task 2020-10-30T18:23:33.402Z] 18:23:33     INFO - GECKO(3069) |   Thread T15 'Timer' (tid=3108, running) created by main thread at:
[task 2020-10-30T18:23:33.402Z] 18:23:33     INFO - GECKO(3069) |     #0 pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:966:3 (firefox+0x5667b)
[task 2020-10-30T18:23:33.403Z] 18:23:33     INFO - GECKO(3069) |     #1 _PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:458:14 (libnspr4.so+0x3c203)
[task 2020-10-30T18:23:33.403Z] 18:23:33     INFO - GECKO(3069) |     #2 PR_CreateThread /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:533:12 (libnspr4.so+0x30b52)
[task 2020-10-30T18:23:33.404Z] 18:23:33     INFO - GECKO(3069) |     #3 nsThread::Init(nsTSubstring<char> const&) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:659:8 (libxul.so+0xaefa27)
[task 2020-10-30T18:23:33.404Z] 18:23:33     INFO - GECKO(3069) |     #4 nsThreadManager::NewNamedThread(nsTSubstring<char> const&, unsigned int, nsIThread**) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadManager.cpp:640:12 (libxul.so+0xaf644a)
[task 2020-10-30T18:23:33.404Z] 18:23:33     INFO - GECKO(3069) |     #5 NS_NewNamedThread(nsTSubstring<char> const&, nsIThread**, already_AddRefed<nsIRunnable>, unsigned int) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:161:57 (libxul.so+0xafc067)
[task 2020-10-30T18:23:33.405Z] 18:23:33     INFO - GECKO(3069) |     #6 NS_NewNamedThread<13> /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:85:10 (libxul.so+0xae8949)
[task 2020-10-30T18:23:33.405Z] 18:23:33     INFO - GECKO(3069) |     #7 TimerThread::Init() /builds/worker/checkouts/gecko/xpcom/threads/TimerThread.cpp:266:9 (libxul.so+0xae8949)
[task 2020-10-30T18:23:33.405Z] 18:23:33     INFO - GECKO(3069) |     #8 TimerThread::AddTimer(nsTimerImpl*) /builds/worker/checkouts/gecko/xpcom/threads/TimerThread.cpp:515:17 (libxul.so+0xaea4bf)
[task 2020-10-30T18:23:33.406Z] 18:23:33     INFO - GECKO(3069) |     #9 nsTimerImpl::InitCommon(mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator> const&, unsigned int, nsTimerImpl::Callback&&) /builds/worker/checkouts/gecko/xpcom/threads/nsTimerImpl.cpp:318:19 (libxul.so+0xafff0d)
[task 2020-10-30T18:23:33.407Z] 18:23:33     INFO - GECKO(3069) |     #10 InitCommon /builds/worker/checkouts/gecko/xpcom/threads/nsTimerImpl.cpp:293:10 (libxul.so+0xb00000)
[task 2020-10-30T18:23:33.408Z] 18:23:33     INFO - GECKO(3069) |     #11 nsTimerImpl::InitWithFuncCallbackCommon(void (*)(nsITimer*, void*), void*, unsigned int, unsigned int, mozilla::Variant<int const, char const*, void (*)(nsITimer*, bool, void*, char*, unsigned long)> const&) /builds/worker/checkouts/gecko/xpcom/threads/nsTimerImpl.cpp:337:10 (libxul.so+0xb00000)
[task 2020-10-30T18:23:33.408Z] 18:23:33     INFO - GECKO(3069) |     #12 InitWithNamedFuncCallback /builds/worker/checkouts/gecko/xpcom/threads/nsTimerImpl.cpp:345:10 (libxul.so+0xaff376)
[task 2020-10-30T18:23:33.408Z] 18:23:33     INFO - GECKO(3069) |     #13 nsTimer::InitWithNamedFuncCallback(void (*)(nsITimer*, void*), void*, unsigned int, unsigned int, char const*) /builds/worker/checkouts/gecko/xpcom/threads/nsTimerImpl.h:235:3 (libxul.so+0xaff376)
[task 2020-10-30T18:23:33.409Z] 18:23:33     INFO - GECKO(3069) |     #14 ResetStartupWriteTimer /builds/worker/checkouts/gecko/startupcache/StartupCache.cpp:820:11 (libxul.so+0x6440436)
[task 2020-10-30T18:23:33.409Z] 18:23:33     INFO - GECKO(3069) |     #15 mozilla::scache::StartupCache::PutBuffer(char const*, mozilla::UniquePtr<char [], mozilla::DefaultDelete<char []> >&&, unsigned int) /builds/worker/checkouts/gecko/startupcache/StartupCache.cpp:469:12 (libxul.so+0x6440436)
[task 2020-10-30T18:23:33.409Z] 18:23:33     INFO - GECKO(3069) |     #16 WriteCachedScript(mozilla::scache::StartupCache*, nsTSubstring<char>&, JSContext*, JS::Handle<JSScript*>) /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSLoaderUtils.cpp:76:14 (libxul.so+0x18bcc68)
[task 2020-10-30T18:23:33.410Z] 18:23:33     INFO - GECKO(3069) |     #17 mozJSComponentLoader::ObjectForLocation(ComponentLoaderInfo&, nsIFile*, JS::MutableHandle<JSObject*>, JS::MutableHandle<JSScript*>, char**, bool, JS::MutableHandle<JS::Value>) /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp:814:10 (libxul.so+0x18a8a49)
[task 2020-10-30T18:23:33.410Z] 18:23:33     INFO - GECKO(3069) |     #18 mozJSComponentLoader::Import(JSContext*, nsTSubstring<char> const&, JS::MutableHandle<JSObject*>, JS::MutableHandle<JSObject*>, bool) /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp:1249:12 (libxul.so+0x18ab878)
[task 2020-10-30T18:23:33.410Z] 18:23:33     INFO - GECKO(3069) |     #19 mozilla::xpcom::ConstructJSMComponent(nsTSubstring<char> const&, char const*, nsISupports**) /builds/worker/workspace/obj-build/xpcom/components/StaticComponents.cpp:1723:3 (libxul.so+0xac03ad)
[task 2020-10-30T18:23:33.411Z] 18:23:33     INFO - GECKO(3069) |     #20 mozilla::xpcom::CreateInstanceImpl(mozilla::xpcom::ModuleID, nsISupports*, nsID const&, void**) /builds/worker/workspace/obj-build/xpcom/components/StaticComponents.cpp (libxul.so+0xabf655)
[task 2020-10-30T18:23:33.412Z] 18:23:33     INFO - GECKO(3069) |     #21 mozilla::xpcom::StaticModule::CreateInstance(nsISupports*, nsID const&, void**) const /builds/worker/workspace/obj-build/xpcom/components/StaticComponents.cpp:12033:10 (libxul.so+0xab5c30)
[task 2020-10-30T18:23:33.413Z] 18:23:33     INFO - GECKO(3069) |     #22 CreateInstance /builds/worker/checkouts/gecko/xpcom/components/nsComponentManager.cpp:176:46 (libxul.so+0xacc194)
[task 2020-10-30T18:23:33.413Z] 18:23:33     INFO - GECKO(3069) |     #23 nsComponentManagerImpl::GetServiceLocked((anonymous namespace)::MutexLock&, (anonymous namespace)::EntryWrapper&, nsID const&, void**) /builds/worker/checkouts/gecko/xpcom/components/nsComponentManager.cpp:1330:17 (libxul.so+0xacc194)
[task 2020-10-30T18:23:33.413Z] 18:23:33     INFO - GECKO(3069) |     #24 nsComponentManagerImpl::GetServiceByContractID(char const*, nsID const&, void**) /builds/worker/checkouts/gecko/xpcom/components/nsComponentManager.cpp:1517:10 (libxul.so+0xacccf0)
[task 2020-10-30T18:23:33.414Z] 18:23:33     INFO - GECKO(3069) |     #25 CallGetService /builds/worker/checkouts/gecko/xpcom/components/nsComponentManagerUtils.cpp:61:43 (libxul.so+0xacf96a)
[task 2020-10-30T18:23:33.414Z] 18:23:33     INFO - GECKO(3069) |     #26 nsGetServiceByContractIDWithError::operator()(nsID const&, void**) const /builds/worker/checkouts/gecko/xpcom/components/nsComponentManagerUtils.cpp:253:21 (libxul.so+0xacf96a)
[task 2020-10-30T18:23:33.415Z] 18:23:33     INFO - GECKO(3069) |     #27 nsCOMPtr_base::assign_from_gs_contractid_with_error(nsGetServiceByContractIDWithError const&, nsID const&) /builds/worker/checkouts/gecko/xpcom/base/nsCOMPtr.cpp:91:7 (libxul.so+0xa13aa7)
[task 2020-10-30T18:23:33.415Z] 18:23:33     INFO - GECKO(3069) |     #28 operator= /builds/worker/workspace/obj-build/dist/include/nsCOMPtr.h:1066:5 (libxul.so+0x63fe0cf)
[task 2020-10-30T18:23:33.416Z] 18:23:33     INFO - GECKO(3069) |     #29 nsAppStartupNotifier::NotifyObservers(char const*) /builds/worker/checkouts/gecko/toolkit/xre/nsAppStartupNotifier.cpp:42:23 (libxul.so+0x63fe0cf)
[task 2020-10-30T18:23:33.416Z] 18:23:33     INFO - GECKO(3069) |     #30 XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:4862:3 (libxul.so+0x63f7992)
[task 2020-10-30T18:23:33.417Z] 18:23:33     INFO - GECKO(3069) |     #31 XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5283:8 (libxul.so+0x63f8be0)
[task 2020-10-30T18:23:33.417Z] 18:23:33     INFO - GECKO(3069) |     #32 XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5339:21 (libxul.so+0x63f8f24)
[task 2020-10-30T18:23:33.417Z] 18:23:33     INFO - GECKO(3069) |     #33 mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:45:12 (libxul.so+0x6403272)
[task 2020-10-30T18:23:33.419Z] 18:23:33     INFO - GECKO(3069) |     #34 do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:218:22 (firefox+0xc7c50)
[task 2020-10-30T18:23:33.419Z] 18:23:33     INFO - GECKO(3069) |     #35 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:336:16 (firefox+0xc7c50)
[task 2020-10-30T18:23:33.419Z] 18:23:33     INFO - GECKO(3069) | SUMMARY: ThreadSanitizer: data race /builds/worker/checkouts/gecko/xpcom/build/XPCOMInit.cpp:639:27 in mozilla::ShutdownXPCOM(nsIServiceManager*)
[task 2020-10-30T18:23:33.420Z] 18:23:33     INFO - GECKO(3069) | ==================
[task 2020-10-30T18:23:33.556Z] 18:23:33     INFO - TEST-INFO | Main app process: killed by SIGIOT
[task 2020-10-30T18:23:33.556Z] 18:23:33     INFO - Buffered messages finished
[task 2020-10-30T18:23:33.556Z] 18:23:33    ERROR - TEST-UNEXPECTED-FAIL | Last test finished | application terminated with exit code -6```

Maybe gXPCOMThreadsShutDown needs to be made atomic?

Dupe of Bug 1674149 ?

Yeah, that looks like the same thing, though in this case the racing thread is the timer thread instead of a DOM worker. We might shut down DOM worker threads earlier(?) but we don't shut down the timer thread until a few lines later.

(In reply to Andrew McCreight [:mccr8] from comment #1)

Maybe gXPCOMThreadsShutDown needs to be made atomic?

I looked into this particular race with the timer thread at some point while debugging nsThreadManager and I think making it atomic would fix it, but I don't really know enough about our shutdown routines to be sure. Though gXPCOMThreadsShutDown is access off the main thread in many places (including DOM worker), so I suppose making it atomic wouldn't hurt anything but I'm not sure if it would fix anything either.

Fixed in Bug 1607138.